框架能處理 request 之後，沒有問題的時候其實沒人在看 log，但只要哪天要查問題，哪個 method、哪個 path、相關的狀態碼、花了多久，每一項都會想知道，這種東西不該等到出事才開始補，而是框架本來就要有，需要的時候打開就好，如果每個 handler 都自己印 log，程式碼很快就會散落一地

這篇實作第一個內建 middleware，LoggingMiddleware，它同時也是驗證第 13-14 篇 pipeline 行為的好場景，一個 middleware 怎麼在 handler 前後都做事

先講清楚相關的實作範圍，這篇做的是 logging middleware，重點在把印 log 這件事從 handler 抽到 pipeline 上，而不是做一套完整的 log 系統，所以你會看到介面只有 info 和 error 兩個方法，輸出就是一行 println，夠這個 middleware 用就好

logger 這條線後面還會再出現幾次，但每一次都是接到別的機制上，第 16 篇排它跟 error handling 的先後順序，第 18 篇把 logger 變成 plugin 的設定項，第 25 篇讓 log level 來自設定檔，第 26 篇把它註冊進 DI 容器，讓 handler 也拿得到同一個實例，至於 SLF4J、JSON 結構化輸出、trace ID 這些正式環境該有的東西，整個系列都不會做，第 32 篇會把它們列在延伸方向裡

先定義要記哪些資訊

log 最少要包含四個東西

• Request method (GET / POST / PUT / DELETE)
• Request path (/api/v1/users/123)
• Response status code (200 / 404 / 500)
• 耗時 (毫秒)

輸出格式先簡單一點

GET /api/v1/users/123 -> 200 (12ms)
POST /users -> 201 (45ms)
GET /missing -> 404 (1ms)

等框架成熟後再擴充成結構化 log (JSON) 也不遲，現在的目標是讓開發者打開 terminal 就能知道發生了什麼事

抽象 Logger，讓 logging 可測試

直接測 stdout 很脆弱，你得攔截 System.out，格式一改測試就爆，比較好的做法是把「怎麼記」抽象成介面，middleware 只負責「記什麼」

Middleware 不需要知道訊息最後送到 stdout、檔案或集中式 logging，只依賴 RelixLogger，測試注入 FakeLogger，正式環境再換成 SLF4J 等實作，middleware 本身不必改動

interface RelixLogger {
    fun info(message: String)
    fun error(message: String, cause: Throwable? = null)
}

兩個方法就夠。正常 request 用 info，exception 用 error，介面上看不到 log level，是因為過濾的責任在 logger 實作那一端，後面「常見陷阱與設計取捨」會說明

框架預設提供一個 console 版本

class ConsoleLogger : RelixLogger {
    override fun info(message: String) {
        println("[Relix] $message")
    }

    override fun error(message: String, cause: Throwable?) {
        System.err.println("[Relix ERROR] $message")
        cause?.printStackTrace(System.err)
    }
}

測試用的假 logger 更簡單，把訊息收集到一個 list 裡

class FakeLogger : RelixLogger {
    val messages = mutableListOf<String>()
    val errors = mutableListOf<String>()

    override fun info(message: String) {
        messages += message
    }

    override fun error(message: String, cause: Throwable?) {
        errors += message
    }
}

有了 FakeLogger，測試可以直接檢查 messages 裡的內容，不用碰 stdout

TDD 先寫測試

測試要確認的行為，log 格式、耗時、不同 status code 的輸出，還有動態路由記下來的是哪一種 path

import kotlin.test.Test
import kotlin.test.assertEquals
import kotlin.test.assertFalse
import kotlin.test.assertNotNull
import kotlin.test.assertTrue

class LoggingMiddlewareTest {

    @Test
    fun `logs method, path, status and timing`() {
        val logger = FakeLogger()

        val app = RelixApplication()
        app.use(loggingMiddleware(logger))
        app.routing {
            get("/hello") { ok("Hello!") }
        }

        val testKit = RelixTestKit(app)
        testKit.handleRequest("GET", "/hello")

        assertEquals(1, logger.messages.size)
        val log = logger.messages.first()
        assertTrue(log.contains("GET"))
        assertTrue(log.contains("/hello"))
        assertTrue(log.contains("200"))
        assertTrue(log.contains("ms"))
    }

    @Test
    fun `logs 404 for missing route`() {
        val logger = FakeLogger()

        val app = RelixApplication()
        app.use(loggingMiddleware(logger))
        app.routing {
            get("/hello") { ok("Hello!") }
        }

        val testKit = RelixTestKit(app)
        testKit.handleRequest("GET", "/missing")

        val log = logger.messages.first()
        assertTrue(log.contains("GET"))
        assertTrue(log.contains("/missing"))
        assertTrue(log.contains("404"))
    }

    @Test
    fun `logs different HTTP methods`() {
        val logger = FakeLogger()

        val app = RelixApplication()
        app.use(loggingMiddleware(logger))
        app.routing {
            get("/users") { ok("list") }
            post("/users") { created("created") }
            delete("/users/{id}") { ok("deleted") }
        }

        val testKit = RelixTestKit(app)
        testKit.handleRequest("GET", "/users")
        testKit.handleRequest("POST", "/users")
        testKit.handleRequest("DELETE", "/users/42")

        assertEquals(3, logger.messages.size)
        assertTrue(logger.messages[0].contains("GET"))
        assertTrue(logger.messages[1].contains("POST"))
        assertTrue(logger.messages[2].contains("DELETE"))
    }

    @Test
    fun `logs actual path, not route template`() {
        val logger = FakeLogger()

        val app = RelixApplication()
        app.use(loggingMiddleware(logger))
        app.routing {
            get("/users/{id}") { ok("user") }
        }

        val testKit = RelixTestKit(app)
        testKit.handleRequest("GET", "/users/42")

        val log = logger.messages.first()
        assertTrue(log.contains("/users/42"))
        assertFalse(log.contains("{id}"))
    }

    @Test
    fun `timing is non-negative`() {
        val logger = FakeLogger()

        val app = RelixApplication()
        app.use(loggingMiddleware(logger))
        app.routing {
            get("/fast") { ok("quick") }
        }

        val testKit = RelixTestKit(app)
        testKit.handleRequest("GET", "/fast")

        val log = logger.messages.first()
        // 從 log 裡取出毫秒數，確認 >= 0
        val msPattern = Regex("""\((\d+)ms\)""")
        // 用 assertNotNull 而不是 assertTrue(match != null)：
        // assertNotNull 有 contract，後面才能直接存取 match.groupValues
        val match = assertNotNull(
            msPattern.find(log),
            "log should contain timing in (Nms) format",
        )
        assertTrue(match.groupValues[1].toLong() >= 0)
    }
}

實作 LoggingMiddleware

Kotlin 有兩種計時方式

• System.currentTimeMillis()，簡單但精度只到毫秒
• TimeSource.Monotonic.markNow() + elapsedNow()，回傳 Duration，精度更高，不受系統時鐘調整影響

這裡我們使用 TimeSource.Monotonic

import kotlin.time.TimeSource

fun loggingMiddleware(logger: RelixLogger = ConsoleLogger()): RelixMiddleware = { next ->
    val method = request.method
    val path = request.path

    val mark = TimeSource.Monotonic.markNow()
    val response = next()
    val elapsed = mark.elapsedNow()

    val ms = elapsed.inWholeMilliseconds
    logger.info("$method $path -> ${response.statusCode} (${ms}ms)")

    response
}

loggingMiddleware 是一個工廠函式，接收 RelixLogger 參數，回傳 RelixMiddleware，用工廠函式而不是直接寫成 val，是因為這樣可以注入不同的 logger

middleware 的結構就是典型的 before/after 模式

1. Before，記下 method、path、開始時間
2. 呼叫 next()
3. After，計算耗時，印出一行 log

next() 把控制權交給下一層 middleware 或 handler，回傳後再記錄 status 與耗時，就是一直說的「洋蔥模型」

不同情境的 log 輸出

看幾個實際的 log 長什麼樣

正常 request

[Relix] GET /hello -> 200 (3ms)
[Relix] POST /users -> 201 (28ms)
[Relix] PUT /users/42 -> 200 (15ms)

找不到路由

[Relix] GET /missing -> 404 (0ms)
[Relix] DELETE /nonexistent -> 404 (0ms)

404 的耗時通常很短，因為 router 查不到就直接回了

method 不允許

[Relix] DELETE /hello -> 405 (0ms)

如果 /hello 只註冊了 GET，用 DELETE 打就會拿到 405

logging middleware 位於 pipeline 最外層，因此 handler 正常回傳、router 回 404 或 middleware 短路時都能留下 log

計時 API 比較，measureTimeMillis vs Duration

Kotlin 標準函式庫有 measureTimeMillis，用起來像這樣

val elapsed = measureTimeMillis {
    next()
}

問題是 measureTimeMillis 的 lambda 回傳值被丟掉了，你拿不到 next() 的 response，要用它就得把 response 存到外部變數

var response: RelixResponse? = null
val elapsed = measureTimeMillis {
    response = next()
}
// 之後用 response!!

這樣子看起來就比較麻煩，而且長的很醜，TimeSource.Monotonic 的寫法乾淨多了，開始打標記，結束算差值，response 正常用 val 接收，所以這裡選用 TimeSource.Monotonic

如果你用的是 Kotlin 1.9+，還有 measureTimedValue 可以用

val (response, elapsed) = measureTimedValue { next() }

這個也不錯，但 TimeSource.Monotonic 的好處是你可以把 mark 存起來，在不同的地方算差值，middleware 的場景裡兩種都行

安裝位置的影響

Logging middleware 應該裝在 pipeline 的最外層，如果裝在 auth 後面，被 auth 短路的 request 就不會被記到

val app = RelixApplication()

// ✓ logging 在最外層，所有 request 都會被記錄
app.use(loggingMiddleware(logger))
app.use(authMiddleware)

// ✗ logging 在 auth 後面，被 auth 擋掉的 request 不會出現在 log
// app.use(authMiddleware)
// app.use(loggingMiddleware(logger))

middleware 的安裝順序就是第 13 篇講的 use() 順序，先 use 的在最外層，最先碰到 request，最後碰到 response

在 main 裡組起來跑一次

前面都是在測試裡面用 FakeLogger 來跑，現在把東西裝進 main，用真的 server 跑一次，看 terminal 實際會長什麼樣

fun main() {
    val app = RelixApplication()

    app.use(loggingMiddleware())

    app.routing {
        get("/hello") { ok("Hello!") }
        get("/users/{id}") { ok("User: ${pathParam("id")}") }
        post("/users") { created("created") }
    }

    JdkHttpServerAdapter(app).start(8080)
}

loggingMiddleware() 這裡沒有傳參數，用的就是預設的 ConsoleLogger，不用自己 new 一個，要換成別的實作再傳進去就好，這正是工廠函式那個預設值的用處

app.use() 寫在 app.routing { } 前面，不過這兩個沒有先後關係，use 排的是 middleware 之間的順序，跟路由什麼時候註冊無關

server 起來之後，另外開一個 terminal 打 request

curl localhost:8080/hello
curl localhost:8080/users/42
curl -X POST localhost:8080/users
curl localhost:8080/missing

跑 server 那個 terminal 就會看到

[Relix] GET /hello -> 200 (1ms)
[Relix] GET /users/42 -> 200 (0ms)
[Relix] POST /users -> 201 (0ms)
[Relix] GET /missing -> 404 (0ms)

四行都不是 handler 印的，handler 從頭到尾只回自己的內容，log 全部來自 pipeline 最外層那一個 middleware

第二行可以對照前面那個測試，動態路由記下來的是 /users/42 而不是 /users/{id}，最後一行則沒有對應的路由，router 回 404，logging 一樣記得到，因為它比 router 更外層

第一行的 1ms 跟後面的 0ms 差在 JVM 剛啟動還要載入類別，JIT 也還沒熱身，第一個 request 幾乎都會比後面慢一點

至於後面三行的 0ms，不是真的沒花時間，是 inWholeMilliseconds 把不到 1 毫秒的部分直接截掉了，這幾個 handler 本來就只回一個字串，本機跑連 1 毫秒都用不到，前面選 TimeSource.Monotonic 是為了精度，結果輸出這一步又把精度丟回去，真的想看清楚就把 inWholeMilliseconds 換成 inWholeMicroseconds，或者直接印 elapsed，Duration 的 toString() 會自己挑合適的單位，輸出會像 312us 這樣

不過對 request log 來說，毫秒其實夠用了，會讓你想查的是那種跑了幾百毫秒的 request，不是 0 跟 1 的差別

補上 log level 過濾

正式環境不會想看到每一筆 request 都印一行，所以要有 log level 過濾，先看這件事該發生在哪一層

RelixLogger 只開 info 和 error 兩個方法，連 level 參數都沒有，這是刻意的，level 過濾是輸出端的責任，不是 middleware 的責任，middleware 只負責說「這件事發生了」，要不要印出來由 logger 實作決定

enum class LogLevel { DEBUG, INFO, WARN, ERROR }

class ConsoleLogger(
    private val minLevel: LogLevel = LogLevel.INFO,
) : RelixLogger {
    override fun info(message: String) {
        if (minLevel > LogLevel.INFO) return
        println("[Relix] $message")
    }

    override fun error(message: String, cause: Throwable?) {
        System.err.println("[Relix ERROR] $message")
        cause?.printStackTrace(System.err)
    }
}

enum 的宣告順序就是嚴重程度，Kotlin 的 enum 會依宣告順序自動實作 Comparable，所以 minLevel > LogLevel.INFO 直接就能比，不用自己寫比大小的邏輯

error() 沒有對應的判斷，因為 ERROR 已經是最高的一級，怎麼設都擋不掉，要真的關掉 error，得再加一個 OFF 進 enum，這裡先不做

有一個不對稱的地方，LogLevel 有 DEBUG 和 WARN，但介面上沒有 debug() 和 warn() 這兩個方法，這是留給實作端的空間，minLevel 設 DEBUG 就是全開，設 WARN 就是只留 error，等介面真的需要那兩個方法時再加，現在加只會多兩個沒人呼叫的方法

前面那個 ConsoleLogger 補上一個有預設值的參數就成了，所以第 18 篇那些 ConsoleLogger() 的寫法一行都不用改

至於 minLevel 該從哪裡來，第 18 篇的 plugin config 換一個 ConsoleLogger(LogLevel.WARN) 進去就好，第 25 篇會讓它直接來自設定檔與環境變數

常見陷阱與設計取捨

接下來幾段都不是要再打進專案的程式碼，而是幾個當初做決定時的考量，還有幾條看過但沒走的路

logging middleware 該不該包 try/catch ?

目前的實作沒有包，如果 next() 丟出 exception，log 那行就不會被執行

解法有兩個，在 logging 裡加 try/catch 確保一定會記 log，或是讓 ErrorHandlingMiddleware (第 16 篇) 裝在 logging 裡面，這樣 exception 會先被轉成 HTTP response，logging 拿到的就是正常的 response

// 選項一：logging 自己包 try/catch(不採用)
fun loggingMiddleware(logger: RelixLogger = ConsoleLogger()): RelixMiddleware = { next ->
    val mark = TimeSource.Monotonic.markNow()
    try {
        val response = next()
        // 正常路徑，跟前面的實作一樣記一行 info
        response
    } catch (e: Exception) {
        // 失敗路徑，耗時要再算一次，status code 也只能自己填一個 500
        // 記完還是得往外丟，不然 exception 就被吃掉了
        throw e
    }
}

// 選項二：靠安裝順序解決(推薦)
app.use(loggingMiddleware(logger))       // 最外層
app.use(errorHandlingMiddleware())       // 把 exception 轉成 response
// → logging 永遠拿到正常的 response，不需要 try/catch

選項二比較乾淨，每個 middleware 只做一件事，不用互相兼顧，相關的內容在下一篇會實作，做出 ErrorHandlingMiddleware 之後有一節專門排這兩個的安裝順序，也會把 request 進出兩層 middleware 的完整順序畫出來

為什麼用工廠函式而不是直接 val ?

loggingMiddleware(logger) 是工廠函式，val loggingMiddleware: RelixMiddleware = { ... } 是全域變數，差別在工廠函式可以傳入不同的 logger，測試時傳 FakeLogger，生產時傳 ConsoleLogger，如果寫成 val，logger 就被寫死了

log 記實際 path 還是路由樣板 ?

request.path 拿到的是 /users/42，不是註冊路由時寫的 /users/{id}。這在目前的架構下也沒得選，logging 裝在 pipeline 最外層，next() 都還沒呼叫，router 自然還沒開始比對，那個時間點框架手上只有原始的 request path

剛好這也正是 log 要的，查問題的時候你想知道是哪一筆 request 出事，/users/42 有用，/users/{id} 什麼也沒告訴你

但同一筆資料換到 metrics 就整個相反，拿 path 當 metrics 的標籤，每一個不同的 id 都會長出一條新的時間序列，幾萬個 user 就是幾萬條，這在 Prometheus 這類系統叫 high cardinality，是很容易把儲存撐爆的錯誤，metrics 要的是 /users/{id}，樣板才是有限的集合

Ktor 也是這樣分工的，CallLogging 記實際 path，MicrometerMetrics 記路由樣板，同一筆 request，兩個 plugin 各取所需

結構化 log vs 人類可讀 log

目前的格式 GET /hello -> 200 (3ms) 是給人看的。如果你的系統用 ELK 或 Datadog 收 log，你可能會想輸出 JSON

{ "method": "GET", "path": "/hello", "status": 200, "duration_ms": 3 }

這個擴充基本上也很簡單，換一個 RelixLogger 實作就好，middleware 本身不用改，因為它透過介面呼叫 info()，不管底層怎麼輸出，這就是為什麼一開始要把 logger 抽成介面

小結

LoggingMiddleware 是 pipeline 的第一個實戰應用，把 logger 抽成介面讓測試可以注入 FakeLogger，用 TimeSource.Monotonic 計時避開 measureTimeMillis 拿不到回傳值的限制，安裝在 pipeline 最外層才能記到所有 request，level 過濾交給 logger 實作那一端，middleware 不碰這件事，是否包 try/catch 取決於你有沒有裝 ErrorHandlingMiddleware，下一篇就來做這件事

下一篇

下一篇做 ErrorHandlingMiddleware，把 handler 裡拋出的 exception 統一轉成 HTTP response，開發模式可回傳例外類別，完整 stack trace 則只寫入 server log

參考資料

• Ktor 官方文件：Call logging
• Ktor 官方文件：Micrometer metrics
• Ktor 原始碼：CallLogging.kt
• Ktor 原始碼：CallLoggingConfig.kt
• Ktor 原始碼：ApplicationCallPipeline.kt
• Kotlin 官方文件：Interfaces
• Kotlin API：TimeSource
• Kotlin API：measureTimeMillis

同步刊登於 Blog

圖片來源：AI 產生